Improve presentation of errors from subprocesses, during installation #10795

pradyunsg · 2022-01-14T10:26:29Z

Before:

After this PR:

pfmoore · 2022-01-14T11:00:44Z

The new version looks amazing! No time for a review right now, but purely based on the usability of the new version, I approve 🙂

pradyunsg · 2022-01-14T11:18:47Z

There is one major difference (you know, other than all the aesthetic improvements) -- there's a lot more lines in the output, on failures with --verbose. This is mostly because:

I changed out setuptools shim to be multi-line, instead of the semi-colon-heavy single line, which adds quite a few lines to the output.
I stopped printing the command line in regular non-verbose mode, but do print the full command when running in verbose mode. I have no clue why pip prints the full command in non-verbose mode but not the verbose mode. :)

pradyunsg · 2022-01-14T18:29:37Z

Okay, the unit test failures are string mismatches, as far as I can tell. I'll fix those in a bit.

This is ready for cloning and playing around with it, so... I'd appreciate feedback on this. You'll get a proverbial cookie if you're able to make the pretty error formatting logic fail with an exception. ^>^

Barring any showstopper concerns, I'd like to get this out in 22.0. Last I checked, the release manager is very excited about this change. ;)

pradyunsg · 2022-01-15T12:04:47Z

OK, I'm gonna need some help figuring out what exactly the Windows failure is. You should be able to attach a debugger on the failing test, since this is a failure happening in-process.

sbidoul · 2022-01-16T16:58:43Z

Hi @pradyunsg this is a great improvement !

I made a couple of tests with metadata preparation and build errors. Works fine.

Looking at your screenshots above I was reminded that it is weird that it prints "Preparing metadata (setup.py)... error" after the error in verbose mode, and before in non verbose mode. The former is a bit weird, but it was like that before and is probably a side effect of the absence of the spinner. So that can be left for future improvements.

👍

pradyunsg · 2022-01-21T15:53:26Z

I got myself a clean Windows VM, and I still can't reproduce the CI failure -- the test passes in that VM. >.<

DiddiLeija · 2022-01-21T15:56:08Z

Hmm... let me try it on my Windows computer ;)

notatallshaw · 2022-01-21T17:03:46Z

I can reproduce the failure, I actually get 5 failures compared to main, including the 1 in the CI, not sure if that makes this less helpful but here are my steps:

Installed fresh Python 3.7.9
Created virtual environment: py -3.7 -m venv .venv
Activated virtual environment: .\.venv\Scripts\activate
Installed test requirements: python -m pip install nox 'virtualenv<20'
Cloned repo: git clone https://github.com/pradyunsg/pip
Entered repo: cd pip
Switched branch: git switch better-subprocess-errors
Ran tests: nox -s test-3.7 -- -m unit --verbose --numprocesses auto --showlocals

Got 5 errors compared to main:

FAILED tests/unit/test_req.py::TestRequirementSet::test_environment_marker_extras - pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_requirement_has_name - pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_correct_number_of_matches - assert 0 == 3
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_candidates_match_requirement - pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed
FAILED tests/unit/test_req.py::TestRequirementSet::test_unhashed_deps_on_require_hashes - pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed

Main currently passes for me (as long as I switch to UTC, filed issue for that #10816)

DiddiLeija · 2022-01-21T17:20:59Z

I tested with WIndows 10, Python 3.9.

Ran nox -s test-3.9 -- -m unit --verbose --numprocesses auto --showlocals and got the following 11 failures:

FAILED tests/unit/test_base_command.py::test_log_command_error - assert False
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[INFO-2019-01-17T06:00:37,040 hello\n2019-01-17T06:00:37,040 world]
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[WARNING-2019-01-17T06:00:37,040 WARNING: hello\n2019-01-17T06:00:37,040 world]
FAILED tests/unit/test_req_file.py::TestProcessLine::test_absolute_local_nested_req_files - pip._internal.exceptions....
FAILED tests/unit/test_req.py::TestRequirementSet::test_environment_marker_extras - pip._internal.exceptions.Metadata...
FAILED tests/unit/test_req.py::TestRequirementSet::test_unhashed_deps_on_require_hashes - pip._internal.exceptions.Me...
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_requirement_has_name - pip._internal.e...
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_correct_number_of_matches - assert 0 == 3
FAILED tests/unit/resolution_resolvelib/test_requirement.py::test_new_resolver_candidates_match_requirement - pip._in...

Some of them came from the issue that @notatallshaw pointed in #10816.

I would like to note that Pytest catched some "stderr outputs", that are just what this PR wanted to do:

------------------------------------------------ Captured stderr call -------------------------------------------------
  error: subprocess-exited-with-error

  × python setup.py egg_info did not run successfully.
  │ exit code: 1
  ╰─> [6 lines of output]
      Traceback (most recent call last):
        File "<string>", line 2, in <module>
        File "<pip-setuptools-caller>", line 23
          __file__ = 'C:\Users\Diego Ramirez\AppData\Local\Temp\pip-temp-rgc41rm6\simple_6b5e182fb1d648d7b07961f9bae809a8\setup.py'
                                                                                                                                   ^
      SyntaxError: (unicode error) 'unicodeescape' codec can't decode bytes in position 2-3: truncated \UXXXXXXXX escape
      [end of output]

  note: This error originates from a subprocess, and is likely not a problem with pip.

pradyunsg · 2022-01-21T17:31:48Z

Does that test also fail on main for you?

DiddiLeija · 2022-01-21T17:34:37Z

Which one?

pradyunsg · 2022-01-21T18:18:02Z

test_unhashed_deps_on_require_hashes

DiddiLeija · 2022-01-21T18:21:31Z

Ok. Seems like it doesn't fail:

FAILED tests/unit/test_base_command.py::test_log_file_command_error - assert False
FAILED tests/unit/test_base_command.py::test_log_command_success - AssertionError: assert '2019-01-17T00:00:37,040 fa...
FAILED tests/unit/test_base_command.py::test_log_command_error - assert False
FAILED tests/unit/test_req_file.py::TestProcessLine::test_absolute_local_nested_req_files - pip._internal.exceptions....
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[INFO-2019-01-17T06:00:37,040 hello\n2019-01-17T06:00:37,040 world]
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[WARNING-2019-01-17T06:00:37,040 WARNING: hello\n2019-01-17T06:00:37,040 world]

pradyunsg · 2022-01-25T00:34:33Z

__file__ = 'C:\Users\Diego Ramirez\AppData\Local\Temp\pip-temp-rgc41rm6\simple_6b5e182fb1d648d7b07961f9bae809a8\setup.py'

OH. Ok ok, Windows paths and escaping is the issue. 🤦🏽

pradyunsg · 2022-01-25T00:46:03Z

Thanks for testing this and posting that output @DiddiLeija! ^>^

It would've taken me a lot longer to figure out what I'd done wrong, if you hadn't posted the output of the runs as you were able to reproduce. Thanks! ^>^

This serves as additional context that can be presented in error messages.

Modernise the shim, to account for the Python 3.2+ support matrix. This also presents clearer error messages on failures, the included comment helps inform users about why this shim exists and the traceback now explicitly mentions `<pip-setuptools-shim>` to make it clearer to users that this shim exists.

This is more in line with the rest of our output presentation logic.

This file should be importable in all other modules, which means it can't be importing any of those modules (to prevent an import loop).

These errors now more clearly note where the error occurred and what component is at fault.

This more clearly states where the error came from, presents it in a more approachable format with context provided for what this error is related to.

These are more pleasing colours and, more importantly, a clearer presentation style of the package vs the error.

I'd like to use this in screenshots, but the os.environ makes it a bit tricky to do.

This helps ensure that they aren't improperly handled due to the newer string-in-string design for the setuptools invocation script.

pradyunsg · 2022-01-25T09:22:15Z

Hurray! It passes!

DiddiLeija · 2022-01-26T16:03:32Z

I tested again. I only had 6 failures.

FAILED tests/unit/test_base_command.py::test_log_command_success - AssertionError: assert '2019-01-17T00:00:37,040 fa...
FAILED tests/unit/test_base_command.py::test_log_command_error - assert False
FAILED tests/unit/test_base_command.py::test_log_file_command_error - assert False
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[INFO-2019-01-17T06:00:37,040 hello\n2019-01-17T06:00:37,040 world]
FAILED tests/unit/test_logging.py::TestIndentingFormatter::test_format_with_timestamp[WARNING-2019-01-17T06:00:37,040 WARNING: hello\n2019-01-17T06:00:37,040 world]
FAILED tests/unit/test_req_file.py::TestProcessLine::test_absolute_local_nested_req_files - pip._internal.exceptions....

But they are exactly the same failures than the main failures (see #10795 (comment)). So, the relevant tests are now passing!

DiddiLeija

I think this can be merged now :)

jezdez

Droool.

pradyunsg changed the title ~~Improve errors from subprocesses, during installation~~ Improve presentation of errors from subprocesses, during installation Jan 14, 2022

pradyunsg added this to the 22.0 milestone Jan 14, 2022

pradyunsg mentioned this pull request Jan 14, 2022

Improve our setuptools shim #10723

Closed

pradyunsg force-pushed the better-subprocess-errors branch from d6cb30f to b1a977d Compare January 14, 2022 12:42

pradyunsg added C: error messages Improving error messages type: enhancement Improvements to functionality labels Jan 14, 2022

pradyunsg force-pushed the better-subprocess-errors branch from 436270b to 90c2719 Compare January 15, 2022 07:36

pradyunsg mentioned this pull request Jan 15, 2022

Add additional diagnostics to our error messages #10421

Open

pradyunsg force-pushed the better-subprocess-errors branch from 90c2719 to 5e0a7a0 Compare January 15, 2022 09:10

pradyunsg mentioned this pull request Jan 17, 2022

Add an opt-out for the “running as root” warning #10556

Closed

1 task

pradyunsg force-pushed the better-subprocess-errors branch from 4ece2fd to b9804e2 Compare January 21, 2022 15:34

pradyunsg mentioned this pull request Jan 21, 2022

Abort immediately on metadata generation failure instead of backtracking #10722

Merged

4 tasks

pradyunsg added 3 commits January 25, 2022 01:38

Require every call_subprocess call-site to pass command_desc

531c991

This serves as additional context that can be presented in error messages.

Use logger.warning instead of warnings.warn

57198c6

This is more in line with the rest of our output presentation logic.

pradyunsg added 13 commits January 25, 2022 01:38

Clearly document that exceptions shouldn't import any internals

543d0b3

This file should be importable in all other modules, which means it can't be importing any of those modules (to prevent an import loop).

Improve presentation of LegacyInstallFailure

2a617d5

These errors now more clearly note where the error occurred and what component is at fault.

Add diagnostics to InstallationSubprocessError

1ee3706

This more clearly states where the error came from, presents it in a more approachable format with context provided for what this error is related to.

Add a dedicated exception for metadata generation failures

d527e85

Add an example setuptools-based package that always fails

68e0bd4

Improve the setuptools caller script

1a0193f

Prettify messages for discarding candidates due to issues

a835e0a

These are more pleasing colours and, more importantly, a clearer presentation style of the package vs the error.

Raise the LegacyInstallFailure exception directly

eb46274

Tweak the chattymodule to not leak potentially information

deb2d75

I'd like to use this in screenshots, but the os.environ makes it a bit tricky to do.

Sort imports

40bed17

📰

ba79b1c

Pacify unit tests

94668c6

Don't duplicate output when raising out of distribution preparation

2e8e5ad

pradyunsg force-pushed the better-subprocess-errors branch from 42300f9 to d39a252 Compare January 25, 2022 01:38

Double-escape paths on Windows

723b2df

This helps ensure that they aren't improperly handled due to the newer string-in-string design for the setuptools invocation script.

pradyunsg force-pushed the better-subprocess-errors branch from d39a252 to 723b2df Compare January 25, 2022 08:24

pradyunsg mentioned this pull request Jan 26, 2022

Release 22.0 #10726

Closed

DiddiLeija approved these changes Jan 26, 2022

View reviewed changes

jezdez approved these changes Jan 26, 2022

View reviewed changes

pradyunsg merged commit 1cda23b into pypa:main Jan 27, 2022

pradyunsg deleted the better-subprocess-errors branch January 27, 2022 07:09

github-actions bot locked as resolved and limited conversation to collaborators Feb 12, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve presentation of errors from subprocesses, during installation #10795

Improve presentation of errors from subprocesses, during installation #10795

pradyunsg commented Jan 14, 2022 •

edited

Loading

pfmoore commented Jan 14, 2022

pradyunsg commented Jan 14, 2022 •

edited

Loading

pradyunsg commented Jan 14, 2022

pradyunsg commented Jan 15, 2022 •

edited

Loading

sbidoul commented Jan 16, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

notatallshaw commented Jan 21, 2022 •

edited

Loading

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 25, 2022

pradyunsg commented Jan 25, 2022

pradyunsg commented Jan 25, 2022

DiddiLeija commented Jan 26, 2022

DiddiLeija left a comment

jezdez left a comment

Improve presentation of errors from subprocesses, during installation #10795

Improve presentation of errors from subprocesses, during installation #10795

Conversation

pradyunsg commented Jan 14, 2022 • edited Loading

pfmoore commented Jan 14, 2022

pradyunsg commented Jan 14, 2022 • edited Loading

pradyunsg commented Jan 14, 2022

pradyunsg commented Jan 15, 2022 • edited Loading

sbidoul commented Jan 16, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

notatallshaw commented Jan 21, 2022 • edited Loading

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 21, 2022

DiddiLeija commented Jan 21, 2022

pradyunsg commented Jan 25, 2022

pradyunsg commented Jan 25, 2022

pradyunsg commented Jan 25, 2022

DiddiLeija commented Jan 26, 2022

DiddiLeija left a comment

Choose a reason for hiding this comment

jezdez left a comment

Choose a reason for hiding this comment

pradyunsg commented Jan 14, 2022 •

edited

Loading

pradyunsg commented Jan 14, 2022 •

edited

Loading

pradyunsg commented Jan 15, 2022 •

edited

Loading

notatallshaw commented Jan 21, 2022 •

edited

Loading